---
title: "11：ロギング"
---

このチュートリアルは、プロキシにより多くの機能を追加することから始めます。このチュートリアルではロギングに着目し、入力されるリクエスト、クライアントに返すレスポンス、その他の類似の統計値に関する情報のキャプチャ方法を学習します。これは企業が全データを追求する必要がある場合、開発者や監査人の役に立ちます。

## 問題点

ロギングについて語る場合、記録する情報量が多い程、デバッグや統計データ収集の目的がより良く達成できると考えています。記録する情報には次のようなものがあります。

* Request
    * Header
    * Body
* Response
    * Header
    * Body
* Request Time
* Response Time
* Response receive completion time
* Remote host IP & port
* Local IP & port
* Extended Information

以前の記事で既にこういった情報を収集する方法を述べてきましたが、このチュートリアルではこれらの情報を、マシンや類似のロギング/スクラッピングサービスでの処理がずっと簡単で利便性の高いJSONフォーマットで保存します。

## ロガープラグイン

ここでは新しいプラグイン (モジュール) を追加して機能を拡張しますが、これはPipyの推奨事項です。チュートリアル [パート 5: プラグイン](/tutorial/05-plugins)で、 *use* フィルターの使用方法を説明し *response* サブパイプラインを追加しました。それを学んだのであれば覚えているはずですが、まだ知らない場合や学んでいないなら、まずそのチュートリアルに戻って学習することを強く推奨します。

``` js
.pipeline('request')
  .use(
    [
      'plugins/router.js',
      'plugins/default.js',
    ],
    'request',
    'response',
    () => __turnDown
  )
```

各プラグインの実行シーケンスはこうなります。

* request: A > B > C
* response: C > B > A

それではプラグイン (logger.js) を設定に加えましょう。このプラグインに簡単にコードを追加します。

``` js
{
  "listen": 8000,
  "plugins": [
    "plugins/router.js",
    "plugins/logger.js",
    "plugins/balancer.js",
    "plugins/default.js"
  ]
}
```

他のプラグインの場合と同様に、ロガープラグインには専用の設定ファイルがあります。このチュートリアルの目的により、ログ情報を受信して保存するホストのURLを保存します。 テスト用にこのサービスのモックを作成しますが、使用事例はさまざまでしょうし、皆さんは既にロギングのスタックを設定しているかもしれません。よってこの設定は、具体的な使用事例に合わせて調整してください。

``` js
{
  "logURL": "http://127.0.0.1:8123/log"
}
```

> 収集したログはネットワーク経由で直接、ElasticSearchやClickHouseのようなストレージサービスへ、バッチ処理で転送されます。ネットワークの状態が十分良ければ、データベースはディスクI/OやFileBeatやFluentdのようなログ収集ツールの展開を回避して、アーキテクチャーの複雑さを軽減できます。ネットワーク上で直接報告する場合はデータをバッファリングしてバッチ転送し、ストレージの負担を軽減します。

それではロガープラグインのコードを書いてみましょう。

### グローバル変数

収集したリクエストとレスポンスの情報を別々に送信したいとは全く思いませんが (そうするとデータの保存やクエリが面倒になります)、ロギング情報を集約して何らかの統計操作を行いたいとは思います。こういうアプローチをしようとすると、リクエスト情報をホストにフォーワードして処理する前にリクエスト情報を記録して、それをターゲットホストから受信したレスポンスと組み合わせなければならず、そのためにはそういった情報を保存する何らかのメカニズムが必要になります。 これを行うのが *グローバル変数* です。もし *グローバル変数* と聞いて恐れをなすなら、それは以前のチュートリアル、特に[コンセプト](/intro/concepts) の *コンテキスト* セクションをまだ読んでいないからです。そこで *グローバル変数* とはコンテキスト固有のもので、手続き型プログラミング言語で学んだことのようには作動しないことを説明しています。

``` js
pipy({
  _logURL: new URL(config.logURL),
  _request: null,
  _requestTime: 0,
  _responseTime: 0,
})

.export('logger', {
  __logInfo: {},
})
```

ここではモジュール変数をエクスポート (エクスポーズ)して、ログの内容を簡単に他のモジュールに拡張できるようにもしています。グローバル変数を定義すれば、リクエストとレスポンスの際にデータを記録できます。

### logger.js

まずスケルトンを書いてみましょう。

``` js
//...
.pipeline('request')
.pipeline('response')
```

これはプラグインとして使用する2組のサブパイプラインです。ログの記録は補助的なサービスで、プロキシサービスの根幹機能に影響を及ぼしてはならず、そのためユーザーに意識されることなく、プロキシサービスの根幹機能に干渉せずにコピーしたデータで行います。

## フィルター

### *fork* フィルター

*fork* フィルターは [ジョイントフィルター](/tutorial/04-routing#ジョイントフィルター) の一種で、サブパイプラインでの現在のコンテキストとメッセージを処理しますが、出力としてサブパイプラインの出力を使用せず、入力をその出力とします。つまりコンテキストのみが影響を受け、現在のパイプラインのメッセージは影響を受けないと考えてください。

*fork* の使い方はとても簡単で、ターゲットのサブパイプラインに供給するだけです。

``` js
//...
.pipeline('request')
  .fork('log-request')

.pipeline('response')
  .fork('log-response')

.pipeline('log-request')

.pipeline('log-response')
```

> *fork* フィルターは、このフィルターによって特定されるサブパイプラインのプロセスが完了するまで、元のパイプラインの処理を継続しない点に注意してください。そのため、サブパイプラインでは時間のかかる操作を避けて、リクエストの性能に与える影響を軽減させることが重要になります。

### handleMessageフィルター

まず受信したリクエストを記録します。

``` js
.pipeline('log-request')
  .handleMessageStart(
    () => _requestTime = Date.now()
  )
  .decompressHTTP()
  .handleMessage(
    '256k',
    msg => _request = msg
  )
```

`Date.now()` 関数を使用して現在の時刻を取得します。`MessageStart` イベントを受信したらリクエストの受信時刻を記録し、`handleMessageStart` フィルターでイベントを処理します。

完全なメッセージを受け取った後、`handleMessage` フィルターを通した完全なリクエストをログに記録します。

* このフィルターの第一引数はメッセージ本体の最大サイズです（省略した場合はデフォルト値の-1、すなわち無制限に設定します）。メモリーの使い過ぎを避けるため、256Kに設定します。
* 第二引数はコールバック関数で、その引数として `Message` オブジェクトを受け取ります。

### mergeフィルター

次に、ターゲットホストから取得したレスポンスを記録する必要があります。

``` js
.pipeline('log-response')
  .handleMessageStart(
    () => _responseTime = Date.now()
  )
  .decompressHTTP()
  .replaceMessage(
    '256k',
    msg => (
      new Message(
        JSON.encode({
          req: {
            ..._request.head,
            body: _request.body.toString(),
          },
          res: {
            ...msg.head,
            body: msg.body.toString(),
          },
          reqTime: _requestTime,
          resTime: _responseTime,
          endTime: Date.now(),
          remoteAddr: __inbound.remoteAddress,
          remotePort: __inbound.remotePort,
          localAddr: __inbound.localAddress,
          localPort: __inbound.localPort,
          ...__logInfo,
        }).push('\n')
      )
    )
  )
  .merge('log-send', () => '')

.pipeline('log-send')
```

> ここでスプレッド演算子を使ってオブジェクトデータをカプセル化します。

*log-response* サブパイプラインで、レスポンスの詳細を記録しています。この時点でログを作成するために必要なデータはすべて揃っているので、データをJSONフォーマットのオブジェクトにラップして、新しい `Message` オブジェクトを作成します。

これで必要なロギング情報を含めた `Message` オブジェクトができましたが、これをロガーに送るべきでしょうか? メッセージ毎にロガーシステムに送信し始めると、IOのオーバーヘッドが大きくなるので性能に影響が出ます。複数のリクエストのログをキャッシュして、バッチで送信した方が良いのではないでしょうか？

*merge* フィルターは *log-send* チャンネルに接続する時に使用します。

*merge* フィルターは [ジョイントフィルター](/tutorial/04-routing#ジョイントフィルター) の1種で、作動の仕方は [フィルター：muxHTTP](/tutorial/03-proxy#フィルターmuxhttp) や *fork* フィルターに似ています。

これはある意味 *muxHTTP* フィルターにも似ていて、複数のストリームをひとつに結合して **共有** チャンネルに送信します。異なる点は *merge* フィルターは出力としてサブパイプラインの出力を使わないことで、その点は *fork* フィルターに似ています。

*merge* フィルターの使用方法は *muxHTTP* と似ていますが、ターゲットとするサブパイプラインに加えてキーを供給する必要もあります。キーを使用する理由の詳細については、[パート 4：ルーティング：接続の共有問題](/tutorial/04-routing#接続の共有問題) を参照してください。

### packフィルター

*log-send* サブパイプラインは親パイプラインからメッセージを受け取ってそれをバッファーに収納します。バッファーにはバッファーサイズやタイムアウト設定などを設定できるオプションがあります。バッファーは最初に条件が一致した指定のターゲット（ここではモックサービス）にフラッシュします。

``` js
.pipeline('log-send')
  .pack(
    1000,
    {
      timeout: 5,
    }
  )
  .replaceMessageStart(
    () => new MessageStart({
      method: 'POST',
      path: _logURL.path,
      headers: {
        'Host': _logURL.host,
        'Content-Type': 'application/json',
      }
    })
  )
  .encodeHTTPRequest()
  .connect(
    () => _logURL.host,
    {
      bufferLimit: '8m',
    }
  )
```

## テストしてみる

テストを開始する前に、ロガーサービスのモックのインスタンスを作成する必要があります。それではPipyを使って、送られてくるデータをコンソールにログ記録するシンプルなサービスを書いてみましょう。

``` js
// mock.js
pipy()

.listen(8123)
  .serveHTTP(
    msg => (
      console.log(`body: ${msg.body}`)
    )
  )
```

Pipy インスタンスは `pipy mock.js` から呼び出し、ロガーサービスのモックの作動を開始し、またプロキシサービスも実行します。プロキシサービスとモックサービスが稼働したら、ターミナルを開いてテストを実施します。

``` shell
curl http://localhost:8000/ip
You are requesting / from ::ffff:127.0.0.1
```

モックサービスウィンドウでは、以下のような出力が表示されます。

``` log
body: {"req":{"protocol":"HTTP/1.1","headers":{"host":"localhost:8000","user-agent":"curl/7.77.0","accept":"*/*"},"method":"GET","path":"/","body":""},"res":{"protocol":"HTTP/1.1","headers":{"connection":"keep-alive"},"status":200,"statusText":"OK","body":"You are requesting / from ::ffff:127.0.0.1\n"},"reqTime":1637938843619,"resTime":1637938843620,"endTime":1637938843620,"remoteAddr":"::1","remotePort":53624,"localAddr":"::1","localPort":8000}
```

## まとめ

このチュートリアルでは多くのことを扱いました。*fork* , *merge* , *pack* のような新しいフィルターを学び、使ってみました。

### 要点

* サブパイプラインの実行シーケンスを拒否すると、*use* フィルターをインポートするプラグインのシーケンスを阻害します。
* *fork* フィルターは実行時にイベントをサブパイプラインにコピーし、サブパイプラインの出力を無視します。*fork* フィルターの出力は受信した入力です。
* *merge* フィルターはある意味 *muxHTTP* フィルターに似ていて、複数のストリームをひとつに結合して **共有** チャンネルに送信します。異なる点は *merge* フィルターは出力としてサブパイプラインの出力を使用しません。この点は *fork* フィルターに似ています。
* *pack* フィルターはメッセージをバッファーに収納します。バッファーサイズやタイムアウトの詳細などを設定できます。


### 次のパートの内容

セキュリティは重要な部分で無視できません。次回はJWT認証機能の追加に挑戦してみましょう。
